Examples of Basic Block Counting

Examples of Basic Block Counting

The examples in this section illustrate how to use prof -pixie to obtain basic block counting information from a profiled version of a C file, espresso.

Example Using prof -pixie -invocations

The partial listing below illustrates the use of the -i[nvocations] option. For each procedure, prof reports the number of times it was invoked from each of its possible callers and lists the procedure(s) that called it.

% prof -pixie -i espresso ------------------------------------------------------------------------------- Profile listing generated Fri May 13 14:25:19 1994 with: prof -pixie -i espresso ... * Sorted in descending order by number of calls per procedure. * Unexecuted procedures are excluded. * The inst column is a static number of instructions. * %coverage column contains the percent inst executed. ------------------------------------------------------------------------------- Total procedure invocations: 12113082 calls(%) cum% inst %coverage procedure (file) 3055229(25.22) 25.22 26 25.00 full_row (espresso:/usr/people/guest/enjoy/008.espresso/setc.c) 966541( 7.98) 33.20 26 25.00 set_or (espresso:/usr/people/guest/enjoy/008.espresso/set.c) 772942( 6.38) 39.58 26 25.00 cleanfree (espresso:/work/irix/lib/libc/libc_64/gen/malloc.c) 611793( 5.05) 44.63 26 25.00 setp_implies ...

The above listing shows the total procedure invocations (calls) during the run: 12113082.

The calls(%) column reports the number of calls (and the percentage of total calls) per procedure. For example, there were 3055229 calls (or 25.22% of the total) spent in the procedure full_row.
The cum% column shows the cumulative percentage of calls. For example, 25.22% of all calls were spent in full_row.
The inst column shows the number of instructions executed for a procedure. For example, there were 26 instructions in the procedure full_row.
The %coverage column reports the percentage of instructions executed. For example, 25.00% of instructions were executed in full_row.
The procedure (file) column lists the procedure and its file. For example, the first line reports statistics for the procedure full_row in the file setc.c.

Example Using prof -pixie -heavy

The following partial listing shows the source code lines responsible for the largest portion of execution time produced with the -heavy option.

% prof -pixie -heavy espresso ------------------------------------------------------------------------------- Profile listing generated Fri May 13 14:28:56 1994 with: prof -pixie -heavy espresso ------------------------------------------------------------------------------- ... * -h[eavy] using basic block counts. * Sorted in descending order by number of cycles per line. * Unexecuted lines are excluded. * The insts column contains distinct executed instructions for this line. ------------------------------------------------------------------------------- cycles(%) cum % line insts procedure (file) 77948528( 4.95%) 4.95% 57 40 cofactor (espresso:/usr/people/guest/enjoy/008.espresso/cofactor.c) 73800963( 4.69%) 9.65% 213 67 essen_parts (espresso:/usr/people/guest/enjoy/008.espresso/expand.c) 53399667( 3.39%) 13.04% 48 29 full_row (espresso:/usr/people/guest/enjoy/008.espresso/setc.c) 44723520( 2.84%) 15.88% 137 22 massive_count (espresso:/usr/people/guest/enjoy/008.espresso/cofactor.c) 38032848( 2.42%) 18.30% 257 39 taut_special_cases (espresso:/usr/people/guest/enjoy/008.espresso/irred.c) ...

The previous partial listing shows basic block counts sorted in descending order. The most heavily used line (57) was in procedure cofactor.

The cycles(%) column shows the total number of program cycles (and percentage of the total number). For example, there were 77948528 cycles (4.95% of the total number) for the procedure cofactor.
The cum% column shows the cumulative percentage of the total program cycles. For example, 4.95% of all program cycles were spent in cofactor. The first three procedures used 13.04% of the total cycles.
The line column lists the line number of the procedure: 57.
The insts column reports the number of distinct instructions that were executed at least once. For example, line 57 had 40 instructions.

Example Using prof -pixie -lines

The following partial listing, produced using the -lines option, shows the execution time spent on each line of code, grouped by procedure.

% prof -pixie -lines espresso ------------------------------------------------------------------------------- Profile listing generated Fri May 13 14:30:49 1994 with: prof -pixie -lines espresso ------------------------------------------------------------------------------- ... * -l[ines] using basic-block counts. * Grouped by procedure. * Major sort on cycles executed per procedure. * Minor sort on line numbers within procedure. * Unexecuted procedures are execluded. ------------------------------------------------------------------------------- cycles(%) cum % line insts procedure (file) 856768( 0.05%) 0.05% 121 12 massive_count (espresso:/usr/people/guest/enjoy/008.espresso/cofactor.c) 25235712( 1.60%) 1.66% 128 12 massive_count (espresso:/usr/people/guest/enjoy/008.espresso/cofactor.c) 934656( 0.06%) 1.72% 134 16 massive_count (espresso:/usr/people/guest/enjoy/008.espresso/cofactor.c) 5963136( 0.38%) 2.10% 135 7 massive_count (espresso:/usr/people/guest/enjoy/008.espresso/cofactor.c) 20870976( 1.33%) 3.42% 136 13 massive_count (espresso:/usr/people/guest/enjoy/008.espresso/cofactor.c) ...

In the previous listing:

The cycles(%) column lists the number of program cycles (and the percentage of the total cycles) for each procedure. For example, there were 856768 program cycles (0.05% of the total) for massive_count.
The cum% column shows the cumulative percentage of the total program cycles. For example, 0.05% of all program cycles were spent in massive_count.
The line and insts columns report the procedure's line number, and number of distinct instructions. For example, for the procedure massive_count, lines 121 and 128 each generated 12 instructions that were executed at least once, and line 134 generated 16 instructions that were executed at least once.

Example Using prof -pixie -quit

You can limit the output of prof to information on only the most time-consuming parts of the program by specifying the -quit option. You can instruct prof to quit after a particular number of lines of output, after listing the elements consuming more than a certain percentage of the total, or after the portion of each listing whose cumulative use is a certain amount.

Consider the following sample listing:

        cycles(%)  cum %  seconds   cycles bytes procedure(file)
                                   /call /line

 360331656(22.90)  22.90     4.80     4626    93
massive_count(espresso:/usr/people/guest/enjoy/008.espresso/cofactor.c)
 174376925(11.08)  33.99     2.33    15479   108
cofactor(espresso:/usr/people/guest/enjoy/008.espresso/cofactor.c)
 157700711(10.02)  44.01     2.10    43817   123
elim_lowering(espresso:/usr/people/guest/enjoy/008.espresso/expand.c)
 155670642( 9.89)  53.91     2.08    49216   156
essen_parts(espresso:/usr/people/guest/enjoy/008.espresso/expand.c)
  66835754( 4.25)  58.15     0.89      691    76
scofactor(espresso:/usr/people/guest/enjoy/008.espresso/cofactor.c)
  66537017( 4.23)  62.38     0.89       21   156
full_row(espresso:/usr/people/guest/enjoy/008.espresso/setc.c)
  57747597( 3.67)  66.05     0.77     1670    87
taut_special_cases(espresso:/usr/people/guest/enjoy/008.espresso/irred.c)

Any one of the following commands eliminates everything from the line starting with 66835754 to the end of the listing:

prof -quit 4
prof -quit 5%
prof -quit 53cum%

Example Using prof -pixie -procedures

The following partial listing, produced with the -procedures option, shows the percentage of execution time spent in each procedure.

% prof -pixie -procedures espresso ------------------------------------------------------------------------------- Profile listing generated Fri May 13 14:33:00 1994 with: prof -pixie -procedures espresso ------------------------------------------------------------------------------- ... * -p[rocedures] using basic-block counts. * Sorted in descending order by the number of cycles executed in each * procedure. Unexecuted procedures are not listed. ------------------------------------------------------------------------------- cycles(%) cum % seconds cycles bytes procedure(file) /call /line 360331656(22.90) 22.90 4.80 4626 93 massive_count(espresso:/usr/people/guest/enjoy/008.espresso/cofactor.c) 174376925(11.08) 33.99 2.33 15479 108 cofactor(espresso:/usr/people/guest/enjoy/008.espresso/cofactor.c) 157700711(10.02) 44.01 2.10 43817 123 elim_lowering(espresso:/usr/people/guest/enjoy/008.espresso/expand.c) 155670642( 9.89) 53.91 2.08 49216 156 essen_parts(espresso:/usr/people/guest/enjoy/008.espresso/expand.c) 66835754( 4.25) 58.15 0.89 691 76 scofactor(espresso:/usr/people/guest/enjoy/008.espresso/cofactor.c)

In the above listing:

The cycles(%) column lists the number of program cycles (and percentage of the total) used. For example, massive_count used 360331656 program cycles (22.90% of the total cycles).
The cum % column reports the cumulative total of all cycles used. For example, massive_count, cofactor, and elim_lowering used 44.01% of the cycles.
The seconds column lists the time used by the procedure (the clock rate, 75 megahertz, is omitted in this example). For example, there were 4.80 seconds used by massive_count.
The cycles/call and bytes/line columns report the average cycles per call, and the bytes of code per line of source text, respectively. For example, massive_count used an average of 4626 cycles per call, and had 93 bytes of generated code per line of source text.
The procedure (file) column lists the procedure, massive_count, and its source file, cofactor.c.

Example Using prof -pixie -procedures -clock

You can add absolute time information to the output by specifying the clock rate, in megahertz, with the -clock option. Partial output looks like this:

% prof -pixie -procedures -clock 20 espresso ------------------------------------------------------------------------------- Profile listing generated Fri May 13 14:34:55 1994 with: prof -pixie -procedures -clock 20 espresso ------------------------------------------------------------------------------- ... * -p[rocedures] using basic-block counts. * Sorted in descending order by the number of cycles executed in each * procedure. Unexecuted procedures are not listed. ------------------------------------------------------------------------------- cycles(%) cum % seconds cycles bytes procedure(file) /call /line 360331656(22.90) 22.90 18.02 4626 93 massive_count(espresso:/usr/people/guest/enjoy/008.espresso/cofactor.c) 174376925(11.08) 33.99 8.72 15479 108 cofactor(espresso:/usr/people/guest/enjoy/008.espresso/cofactor.c) 157700711(10.02) 44.01 7.89 43817 123 elim_lowering(espresso:/usr/people/guest/enjoy/008.espresso/expand.c) ...

In the previous listing, the seconds column lists the number of seconds spent in each procedure. For example 18.02 seconds were spent in the procedure massive_count. The time (computed by the profiler), in seconds, is based on the machine speed specified with the -clock option (in megahertz). In this example, the speed specified is 20 megahertz.

Example Using prof -pixie -dis

You can use the -dis option to prof to disassemble the analyzed object code and see the number of cycles it takes to execute an instruction. Check the disassembled code for stalls (wasted cycles) and the number of instructions per cycle. For example, partial output looks like this:

-------------------------------------------------------------------------------
Profile listing generated Fri May 13 14:37:07 1994
    with:       prof -pixie -dis espresso
-------------------------------------------------------------------------------

Total cycles    Total Time  Instructions Cycles/inst    Clock
  1573247788        20.98s    2093722528       0.751  75.0MHz
...
/usr/people/guest/enjoy/008.espresso/main.c
main: <0x1001c90c-0x1001e238>
    219 total cycles(0.00%) invoked 1 times, average 219 cycles/invocation
  [20] 0x1001c90c       0x67bdfe40      daddiu  sp,sp,-448      # 0
                <1 cycle stall for following instruction>
  [20] 0x1001c910       0xffbf0170      sd      ra,368(sp)      # 2
  [20] 0x1001c914       0xffb00158      sd      s0,344(sp)      # 3
  ...
  [152] 0x1000b178 0x1540000d bne t2,zero,0x1000b1b0 # 23
  [152] 0x1000b17c 0x016c5823 subu t3,t3,t4 # 23
  Preceding branch executed 1000 times, taken 0 times.
  ^--- 3000 total cycles(0.01%) executed 1000 times, average 3 cycles.---^
  ...

The previous listing shows statistics about the procedure main in the file main.c and lists the beginning and ending addresses of main: <0x1001c90c-0x1001e238>

The first column lists the line number of the instruction: [20]
The second column lists the beginning address of the instruction: 0x1001c90c.
The third column shows the instruction in hexadecimal: 0x67bdfe40.
The next column reports the assembler form (mnemonic) of the instruction: daddiu sp,sp,-448.
The last column reports the cycle in which the instruction executed: # 2

Other information includes:

The number of times an above branch was executed and taken:
Preceding branch executed 1000 times, taken 0 times
The total number of cycles in a basic block and the percentage of the total cycles for that basic block, the number of times the branch terminating that basic block was executed, and the number of cycles for one execution of that basic block:
300 total cycles(0.01%) executed 1000 times, average3 cycles.
Any cycle stalls (cycles that were wasted)

For information on cycle stalls and what causes them, see the MIPS Microprocessor Chip Set User's Guide for your architecture.